P12-2. 카오스 엔지니어링과 근본 원인 분리 종합 실습 - 실습 검증

1. 시나리오 A: 네트워크/메시 계층 지연 주입 및 RCA 검증

1.1 Istio VirtualService를 통한 3초 지연 주입 ($HOME\mesh-study\part12-chaos-vs.yaml)

전체 서비스에 영향을 주지 않도록 폭발 반경(Blast Radius)을 /chaos-net URI 프리픽스로 한정한 VirtualService를 part1-demo 네임스페이스에 배포한다.

@"
apiVersion: networking.istio.io/v1
kind: VirtualService
metadata:
  name: chaos-network-delay
  namespace: part1-demo
spec:
  hosts:
    - order-api.part1-demo.svc.cluster.local
  http:
    - match:
        - uri:
            prefix: /chaos-net
      fault:
        delay:
          percentage:
            value: 100
          fixedDelay: 3s
      route:
        - destination:
            host: order-api.part1-demo.svc.cluster.local
    - route:
        - destination:
            host: order-api.part1-demo.svc.cluster.local
"@ | Set-Content -Path "$HOME\mesh-study\part12-chaos-vs.yaml" -Encoding UTF8

kubectl apply -f "$HOME\mesh-study\part12-chaos-vs.yaml"

1.2 지연 트래픽 발생 및 클라이언트 체감 시간 실측

study-client에서 order-api 서비스(포트 80)의 /chaos-net 경로를 호출하고 응답 헤더와 총 소요 시간(%{time_total})을 측정한다.

kubectl exec -n part1-demo study-client -- curl -i -s -w "\nTotalTime: %{time_total}s\n" http://order-api.part1-demo.svc.cluster.local/chaos-net

실제 응답 결과:

HTTP/1.1 200 OK
x-powered-by: Express
content-type: application/json; charset=utf-8
content-length: 700
date: Sun, 25 Oct 2026 07:48:43 GMT
x-envoy-upstream-service-time: 3
server: istio-envoy
x-envoy-decorator-operation: order-api.part1-demo.svc.cluster.local:80/chaos-net*

{
  "path": "/chaos-net",
  "headers": {
    "host": "order-api.part1-demo.svc.cluster.local",
    "user-agent": "curl/8.10.1",
    "x-request-id": "965249ad-f294-97d5-aa36-66f2ce95d80d",
    "traceparent": "00-ce983b5a2ca53e31b0dbdb20d4eb17c2-8b072c198b8e6281-01"
  },
  "os": {
    "hostname": "order-api-v2-677cff8fd5-wz8sp"
  }
}
TotalTime: 3.280888s

• 클라이언트가 체감한 총 응답 시간(TotalTime)은 **3.28초**이지만, 응답 헤더의 x-envoy-upstream-service-time은 단 **3 (3ms)**이다!

1.3 증거 1: Waypoint Envoy Access Log (Loki) 분석

kubectl logs -n part1-demo deploy/waypoint --tail=5

실제 로그 출력:

[2026-10-25T07:48:40.449Z] "GET /chaos-net HTTP/1.1" 200 DI via_upstream - "-" 0 700 3005 3 "-" "curl/8.10.1" "965249ad-f294-97d5-aa36-66f2ce95d80d" "order-api.part1-demo.svc.cluster.local" "envoy://connect_originate/10.244.2.10:8080" inbound-vip|80|http|order-api.part1-demo.svc.cluster.local envoy://internal_client_address/ 10.96.72.69:80 10.244.2.7:41870 - -

1.4 증거 2: Grafana Tempo 분산 추적 Span 분석

위 응답 본문의 traceparent에서 추출한 Trace ID(ce983b5a2ca53e31b0dbdb20d4eb17c2)로 Tempo API를 조회한다.

kubectl exec -n part1-demo study-client -- curl -s http://tempo.monitoring.svc.cluster.local:3200/api/traces/ce983b5a2ca53e31b0dbdb20d4eb17c2

실제 응답 결과 (핵심 Span 발췌):

{
  "spans": [
    {
      "name": "order-api.part1-demo.svc.cluster.local:80/chaos-net*",
      "kind": "SPAN_KIND_SERVER",
      "startTimeUnixNano": "1792914520449633000",
      "endTimeUnixNano": "1792914523455242000",
      "attributes": [
        { "key": "guid:x-request-id", "value": { "stringValue": "965249ad-f294-97d5-aa36-66f2ce95d80d" } },
        { "key": "http.status_code", "value": { "stringValue": "200" } },
        { "key": "response_flags", "value": { "stringValue": "DI" } },
        { "key": "istio.source_workload", "value": { "stringValue": "study-client" } },
        { "key": "istio.destination_workload", "value": { "stringValue": "order-api-v2" } },
        { "key": "http.url", "value": { "stringValue": "http://order-api.part1-demo.svc.cluster.local/chaos-net" } }
      ]
    }
  ]
}

• endTimeUnixNano - startTimeUnixNano = 3,005,609,000 ns (3,005.6 ms) 동안 Span이 유지되었으며, response_flags: "DI" 태그가 박혀 있어 백엔드 코드나 DB를 뒤질 필요 없이 100% 메시/네트워크 계층 지연임을 확증한다.

2. 시나리오 B: PostgreSQL 18 Row-Level Lock 경합 유발 및 RCA 검증

이번에는 네트워크/메시 계층은 전혀 건드리지 않고, 클러스터 외부의 PostgreSQL 18 VM(pg-vm.mesh.internal, ordersdb)에서 **선행 트랜잭션이 id = 1 행을 배타적으로 잠근 상태(SELECT ... FOR UPDATE + pg_sleep(5))**에서 후행 트랜잭션이 동일 행에 UPDATE를 수행할 때 관측 파이프라인에 어떤 지문이 남는지 검증한다.

2.1 동시 세션 Row Lock 경합 실행 및 실시간 상태 캡처

PowerShell 백그라운드 잡(Start-Job)을 이용해 **Session 1(Blocker)**과 **Session 2(Waiter)**를 동시에 실행하고, 락 경합이 진행 중인 시점과 종료 직후의 메트릭·DB 뷰·Waypoint TCP 로그를 한 번에 수집한다.

# 1. Session 1: id=1 행에 FOR UPDATE 배타 락을 걸고 5초간 대기
$job1 = Start-Job -ScriptBlock {
  kubectl exec -n part1-demo pg-client -- env PGPASSWORD=meshpass psql -h pg-vm.mesh.internal -U meshuser -d ordersdb -c "BEGIN; SELECT * FROM mesh_orders WHERE id = 1 FOR UPDATE; SELECT pg_sleep(5); COMMIT;"
}
Start-Sleep -Seconds 1

# 2. Session 2: 동일 id=1 행에 UPDATE 시도 (Session 1이 커밋할 때까지 Row Lock 대기!)
$job2 = Start-Job -ScriptBlock {
  kubectl exec -n part1-demo pg-client -- env PGPASSWORD=meshpass psql -h pg-vm.mesh.internal -U meshuser -d ordersdb -c "UPDATE mesh_orders SET item = 'CHAOS_DB_LOCK' WHERE id = 1;"
}
Start-Sleep -Seconds 2

# 3. 실시간 pg_stat_activity 락 대기 상태 조회 (Part 07 검증 쿼리 동일)
kubectl exec -n part1-demo pg-client -- env PGPASSWORD=meshpass psql -h pg-vm.mesh.internal -U meshuser -d ordersdb -c "SELECT pid, state, wait_event_type, wait_event, pg_blocking_pids(pid) AS blocked_by, left(query, 55) AS query_snippet FROM pg_stat_activity WHERE datname = 'ordersdb' AND pid <> pg_backend_pid();"

Wait-Job $job1, $job2 | Out-Null
Receive-Job $job1
Receive-Job $job2

락 경합 발생 중 pg_stat_activity 포착 결과:

 pid | state  | wait_event_type |  wait_event   | blocked_by |                      query_snippet                      
-----+--------+-----------------+---------------+------------+---------------------------------------------------------
  39 | active | Timeout         | PgSleep       | {}         | BEGIN; SELECT * FROM mesh_orders WHERE id = 1 FOR UPDAT
  40 | active | Lock            | transactionid | {39}       | UPDATE mesh_orders SET item = 'CHAOS_DB_LOCK' WHERE id 

• 범인 특정 (blocked_by: {39}): pid 40(UPDATE 세션)이 wait_event_type = Lock, wait_event = transactionid 상태로 멈춰 있으며, 이를 가로막고 있는 블로커가 **pid 39(SELECT ... FOR UPDATE 세션)**임을 PostgreSQL 엔진이 직접 지목한다.

2.2 증거 1: pg_stat_statements 누적 실행 시간 폭증 확인

락 경합이 해소된 직후 pg_stat_statements 뷰를 조회하여 SQL 구문별 실제 소요 시간을 확인한다.

kubectl exec -n part1-demo pg-client -- env PGPASSWORD=meshpass psql -h pg-vm.mesh.internal -U meshuser -d ordersdb -c "SELECT calls, roundnumeric, 2) AS total_ms, round(mean_exec_time::numeric, 2) AS mean_ms, left(query, 60 AS query FROM pg_stat_statements WHERE query LIKE '%mesh_orders%' ORDER BY total_exec_time DESC LIMIT 5;"

실제 출력 결과:

 calls | total_ms | mean_ms |                       query                        
-------+----------+---------+----------------------------------------------------
     3 |  8451.25 | 2817.08 | UPDATE mesh_orders SET item = $1 WHERE id = $2
     3 |     6.85 |    2.28 | SELECT * FROM mesh_orders WHERE id = $1 FOR UPDATE
     1 |     3.45 |    3.45 | TRUNCATE TABLE mesh_orders RESTART IDENTITY
     1 |     2.15 |    2.15 | VACUUM mesh_orders
     1 |     0.17 |    0.17 | INSERT INTO mesh_orders (item) VALUES ($1)
(5 rows)

• 단 1건의 Row Update인데도 선행 트랜잭션의 잠금 해제 대기 시간이 고스란히 쿼리 실행 시간에 합산되어 total_ms가 **8,451.25 ms (mean_ms: 2,817.08 ms)**로 치솟았다! 반면 잠금을 먼저 획득한 SELECT ... FOR UPDATE 자체는 평균 **2.28 ms**밖에 걸리지 않았다.

2.3 증거 2: Waypoint TCP Access Log (Loki) 비교

이번에는 part1-demo의 Waypoint 프록시가 외부 PostgreSQL VM(pg-vm.mesh.internal, 172.19.0.7:5432)으로 중계한 TCP 액세스 로그를 확인한다.

kubectl logs -n part1-demo deploy/waypoint --tail=10 | Select-String "10.244.2.11"

실제 로그 출력:

[2026-10-25T07:51:46.714Z] "- - -" 0 - - - "-" 441 925 67 - "-" "-" "-" "-" "172.19.0.7:5432" inbound-vip|5432|tcp|pg-vm.mesh.internal 10.244.2.21:38628 240.240.0.50:5432 10.244.2.11:58904 - -
[2026-10-25T07:51:47.350Z] "- - -" 0 - - - "-" 331 862 5086 - "-" "-" "-" "-" "172.19.0.7:5432" inbound-vip|5432|tcp|pg-vm.mesh.internal 10.244.2.21:38636 240.240.0.50:5432 10.244.2.11:58904 - -
[2026-10-25T07:51:47.919Z] "- - -" 0 - - - "-" 305 637 4545 - "-" "-" "-" "-" "172.19.0.7:5432" inbound-vip|5432|tcp|pg-vm.mesh.internal 10.244.2.21:38652 240.240.0.50:5432 10.244.2.11:58904 - -

• 첫 번째 줄 (duration = 67ms): 락이 없을 때의 일반 조회 쿼리 세션은 67ms 만에 종료되었다.
• 두 번째 줄 (duration = 5086ms): pg_sleep(5)를 포함한 Blocker 세션(38636)이 5,086ms 동안 TCP 연결을 점유했다.
• 세 번째 줄 (duration = 4545ms): 1초 뒤 진입한 UPDATE 세션(38652)이 Row Lock에 가로막혀 4,545ms 동안 대기하다가 Blocker가 커밋된 직후 함께 완료되었다. 이때 %RESPONSE_FLAGS%는 -로, 네트워크나 메시 계층에는 아무런 결함이 없었음을 증명한다!

3. 실습 정리 (카오스 주입 리소스 제거)

실험이 끝났으므로 시나리오 A에서 주입한 VirtualService/chaos-network-delay를 삭제하여 클러스터를 정상 상태(Steady State)로 복원한다.

kubectl delete virtualservice chaos-network-delay -n part1-demo

4. 실전 장애 대응 런북 (RCA Cheat Sheet)

5. 셀프 체크 Q&A

• Q1. 클라이언트에서 3초 응답 지연이 발생했는데, Waypoint 액세스 로그에 200 DI ... 3005 3이라고 기록되었다. 백엔드 개발자에게 애플리케이션 코드 최적화를 요청해야 하는가?
  • A1. 아니다. 3005는 전체 소요 시간(3,005ms)이고 그 뒤의 3은 백엔드 컨테이너가 실제로 처리한 시간(upstream_service_time = 3ms)이다. 또한 DI(Delay Injected) 플래그는 Istio VirtualService에서 인위적인 지연 주입이 활성화되어 있음을 뜻하므로, 백엔드 코드가 아니라 서비스 메시 라우팅 정책(VirtualService)을 점검해야 한다.
• Q2. 반대로 Waypoint 로그에서 RESPONSE_FLAGS는 -이고 DB로 향하는 TCP 세션의 DURATION이 4545ms로 증가했다면 어디를 확인해야 하는가?
  • A2. 네트워크/메시 계층은 정상적으로 패킷을 전달하고 있으며 데이터베이스 내부에서 응답이 지연되고 있는 상황이다. 즉시 VictoriaMetrics의 pg_locks_count 메트릭과 PostgreSQL의 pg_stat_activity(wait_event_type, pg_blocking_pids) 및 pg_stat_statements를 조회하여 Row Lock 경합인지 슬로우 쿼리인지 분리해야 한다.

네비게이션